Rework logging #300

uzlonewolf · 2023-03-14T09:04:40Z

I recently discovered another issue with having tons of devices. Like I mentioned in #208 (comment), I'm dumping a bunch of device sockets into select.select() just like the scanner does. Do you know what happens if you turn debug on and then poll the status of 52 devices simultaneously? It's... not pretty. So, I reworked the logging. Log messages now include the "name" of the source, which for devices is i.e. "tinytuya.OutletDevice.eb1######s". Initially I removed the red coloring of the text from the message, but then decided it was probably there for a reason and put it back. I did keep the device ID in cyan though. Red removed:

Red put back:

When I added the per-device debug toggle I also made its color selection independent (default is to match the global). I didn't intend it to be this way, but it worked out really well as it allows things like:

Anyway, I have this as a draft as it needs a *lot* more testing. I've only verified it works for basic functions.

jasonacox · 2023-03-15T03:36:25Z

I love this!!!

jasonacox · 2023-03-15T03:52:26Z

tinytuya/core.py

@@ -479,7 +488,6 @@ def parse_header(data):
        #seqno |= unknown << 32
        total_length = payload_len + header_len + len(SUFFIX_6699_BIN)
    else:
-        #log.debug('Header prefix wrong! %08X != %08X', prefix, PREFIX_VALUE)


While we are here, should we add a note?

# Tuya protocol should include a header prefix 0x55AA (3.1, 3.2, 3.3, 3.4) or 0x6699 (3.5) # (see https://github.com/jasonacox/tinytuya/discussions/260)

And instead of "Header prefix wrong!" - should we error out with "Header prefix unknown!" ? Not that Tuya would ever change that with the next protocol rev. 😉

jasonacox · 2023-03-15T03:59:47Z

tinytuya/Contrib/ThermostatDevice.py

+                    # FIXME: make a logger available here
+                    #log.info( 'CF is: %r %r %r cool: %r %r %r', cf, self.heatto, heatto / 100, self.coolto, coolto / 100, self.time )


FIXME - I'm sure you know, just adding to my review

Yeah, I'm not sure what I'm going to do about that one, it's buried like 3 classes deep. I may just remove it, though having a logger available there for debugging may be needed at some point.

Sortof gross, but possibly define a global scoped log (glog) to use for this one?

tinytuya/Contrib/ThermostatDevice.py

jasonacox · 2023-03-15T04:07:56Z

tinytuya/__main__.py

+tinytuya.set_debug(debug, color)
+#if debug:
+#    if color:
+#        logging.basicConfig( format="\x1b[0m\x1b[31;1m%(levelname)s:\x1b[22m%(name)s:\x1b[39;2m%(message)s\x1b[0m", level=logging.DEBUG )
+#    else:
+#        logging.basicConfig( level=logging.DEBUG )
+
+if state == 1:
+    from . import wizard
+else:
+    from . import scanner


I'm slow or tired or both... why do we want to defer? Does scanner log logic infect wizard?

I'll most likely remove that one and put it back like it was. I was doing a lot of experimenting and at one point tried to enable debugging before tinytuya was loaded to get the 2 version lines, but it ended up not working and I reverted most of it.

jasonacox · 2023-03-15T04:09:34Z

tinytuya/core.py

@@ -67,7 +67,7 @@
 import struct
 import sys
 import time
-from colorama import init
+from colorama import init, Fore, Back, Style


Ok, love this!!!

jasonacox · 2023-03-15T04:13:01Z

tinytuya/core.py

+
+    if color:
+        # \x1b[39;2m
+        fmt = "\x1b[0m\x1b[31;1m%(levelname)s:\x1b[22m%(name)s:\x1b[31;1m%(message)s\x1b[0m"


I haven't tried, but wonder if we could leverage more colorama here instead to make it more readable. I mean, it's fine.

Yeah, I originally wanted to but couldn't decide between a + b + '%(string)' + c +d (ugh) or doing %s%s%s%s%s%s while trying to get the % formatting to not mangle the embedded %'s (also ugh). I'll see if I can find a more-readable way that I'm happy with.

Ok, I think the choice is between
fmt = ''.join( (Style.RESET_ALL, Fore.RED, Style.BRIGHT, '%(levelname)s:', Style.NORMAL, '%(name)s:', Fore.RED, Style.BRIGHT, '%(message)s', Style.RESET_ALL) )
and
fmt = Style.RESET_ALL + Fore.RED + Style.BRIGHT + '%(levelname)s:' + Style.NORMAL + '%(name)s:' + Fore.RED + Style.BRIGHT + '%(message)s' + Style.RESET_ALL

Any preference?

I prefer the second one (addition). Very simple. Also, I can't get the first one to work in my test.

TypeError: str.join() takes exactly one argument (10 given)

fmt = (Style.RESET_ALL + Fore.RED + Style.BRIGHT + '%(levelname)s:' + Style.NORMAL + '%(name)s:' + Fore.RED + Style.BRIGHT + '%(message)s' + Style.RESET_ALL)

Ah, I forgot the parentheses around the list, should have been fmt = ''.join( (...) ). Oh well, we're using the additive one anyway.

While I was at it I rewrote termcolor() as well:

def termcolor(color=True): if color is False: # Disable Terminal Color Formatting bold = subbold = normal = dim = alert = alertdim = cyan = red = yellow = "" else: # Terminal Color Formatting bold = Style.RESET_ALL + Fore.LIGHTWHITE_EX + Style.BRIGHT subbold = Style.RESET_ALL + Fore.GREEN normal = Style.RESET_ALL dim = Style.RESET_ALL + Fore.LIGHTWHITE_EX + Style.DIM alert = Style.RESET_ALL + Fore.LIGHTRED_EX + Style.BRIGHT alertdim = Style.RESET_ALL + Fore.LIGHTRED_EX + Style.DIM cyan = Style.RESET_ALL + Fore.CYAN red = Style.RESET_ALL + Fore.RED yellow = Style.RESET_ALL + Fore.YELLOW return bold,subbold,normal,dim,alert,alertdim,cyan,red,yellow

For join, we would need to make it into an array. I saw some post that join can be faster than addition, but it wasn't apparent to me and I still think the addition is cleaner:

from colorama import Fore, Style import time print("\nJoin Method: ") start = time.time() for x in range(200): fmt = ''.join([Style.RESET_ALL, Fore.RED, Style.BRIGHT, '%(levelname)s:', Style.NORMAL, '%(name)s:', Fore.RED, Style.BRIGHT, '%(message)s', Style.RESET_ALL]) end = time.time() print("The time difference is :", end - start) print("\nAddition Method: ") start = time.time() for x in range(200): fmt = (Style.RESET_ALL + Fore.RED + Style.BRIGHT + '%(levelname)s:' + Style.NORMAL + '%(name)s:' + Fore.RED + Style.BRIGHT + '%(message)s' + Style.RESET_ALL) end = time.time() print("The time difference is :", end - start)

Nice! Yes, love the termcolor() update!

Upping the loop count to 200,000 makes it a bit more obvious, but the difference is so minuscule it's not worth worrying about. I don't really care either way and currently have it as:

if color: fmt = Style.RESET_ALL + Fore.RED + Style.BRIGHT + '%(levelname)s:' + Style.NORMAL + '%(name)s:' + Fore.RED + Style.BRIGHT + '%(message)s' + Style.RESET_ALL else: fmt = "%(levelname)s:%(name)s:%(message)s"

Rework logging

caaf323

jasonacox reviewed Mar 15, 2023

View reviewed changes

tinytuya/Contrib/ThermostatDevice.py Show resolved Hide resolved

jasonacox reviewed Mar 15, 2023

View reviewed changes

Update color formatting to use colorama more, and misc updates

ba3efad

uzlonewolf mentioned this pull request Mar 21, 2023

Fetch the device list a 2nd time to make sure we have the local key #306

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Rework logging #300

Rework logging #300

uzlonewolf commented Mar 14, 2023

jasonacox commented Mar 15, 2023

jasonacox Mar 15, 2023

jasonacox Mar 15, 2023

uzlonewolf Mar 15, 2023

jasonacox Mar 15, 2023

jasonacox Mar 15, 2023

uzlonewolf Mar 15, 2023

jasonacox Mar 15, 2023

jasonacox Mar 15, 2023

uzlonewolf Mar 15, 2023

uzlonewolf Mar 15, 2023 •

edited

Loading

jasonacox Mar 15, 2023 •

edited

Loading

uzlonewolf Mar 15, 2023

jasonacox Mar 15, 2023

jasonacox Mar 15, 2023

uzlonewolf Mar 15, 2023

		# FIXME: make a logger available here
		#log.info( 'CF is: %r %r %r cool: %r %r %r', cf, self.heatto, heatto / 100, self.coolto, coolto / 100, self.time )

Rework logging #300

Are you sure you want to change the base?

Rework logging #300

Conversation

uzlonewolf commented Mar 14, 2023

jasonacox commented Mar 15, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

uzlonewolf Mar 15, 2023 • edited Loading

Choose a reason for hiding this comment

jasonacox Mar 15, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

uzlonewolf Mar 15, 2023 •

edited

Loading

jasonacox Mar 15, 2023 •

edited

Loading